JVM GC分析总结

发表于 | 分类于 | | 浏览 次

FullGC发生的条件

  • 没有配置 -XX:+DisableExplicitGC情况下System.gc()可能会触发FullGC；
  • Promotion failed；
  • concurrent mode failure；
  • Metaspace Space使用达到MaxMetaspaceSize阈值；
  • 执行jmap -histo:live或者jmap -dump:live；
1
说明：统计发现之前YGC的平均晋升大小比目前old gen剩余的空间大，触发的是CMS GC；如果配置了CMS，并且Metaspace Space使用量达到MetaspaceSize阈值也是触发CMS GC；

执行jmap -histo:live触发FullGC的gc log如下–关键词Heap Inspection Initiated GC，通过jstat -gccause pid 2s的LGCC列也能看到同样的关键词：

1
[Full GC (Heap Inspection Initiated GC) 2018-03-29T15:26:51.070+0800: 51.754: [CMS: 82418K->55047K(131072K), 0.3246618 secs] 138712K->55047K(249088K), [Metaspace: 60713K->60713K(1103872K)], 0.3249927 secs] [Times: user=0.32 sys=0.01, real=0.32 secs]

执行jmap -dump:live触发FullGC的gc log如下–关键词Heap Dump Initiated GC，通过jstat -gccause pid 2s的LGCC列也能看到同样的关键词：

1
[Full GC (Heap Dump Initiated GC) 2018-03-29T15:31:53.825+0800: 354.510: [CMS2018-03-29T15:31

什么样的JVM和GC才是正常的？

GC是否正常，首先就要看YoungGC，OldGC和FullGC是否正常；无论是定位YoungGC，OldGC，FullGC哪一种GC，判断其是否正常主要从两个维度：GC频率和STW时间；要得到这两个维度的值，我们需要知道JVM运行了多久，执行如下命令即可：

1
ps -p pid -o etime

运行结果参考如下，表示这个JVM运行了24天16个小时37分35秒，如果JVM运行时间没有超过一天，执行结果类似这样”16:37:35”：

1
2
3
[afei@ubuntu ~]$ ps -p 11864 -o etime
    ELAPSED
24-16:37:35

正常的GC需要满足的条件（参考，不一定完全一样）

  1. YoungGC频率不超过2秒/次；
  2. CMS GC频率不超过1天/次；
  3. 每次YoungGC的时间不超过15ms；
  4. FullGC频率尽可能完全杜绝；

YGC

YGC是最频繁发生的，发生的概率是OldGC和FullGC的的10倍，100倍，甚至1000倍。同时YoungGC的问题也是最难定位的。这里给出YGC定位三板斧（都是踩过坑）：

  1. 查看服务器SWAP&IO情况，如果服务器发生SWAP，会严重拖慢GC效率，导致STW时间异常长，拉长接口响应时间，从而影响用户体验（推荐神器sar，yum install sysstat即可，想了解该命令，请搜索”linux sar“）；
  2. 查看StringTable情况（请参考：探索StringTable提升YGC性能）
  3. 排查每次YGC后幸存对象大小（JVM模型基于分配的对象朝生夕死的假设设计，如果每次YGC后幸存对象较大，可能存在问题）

OldGC

上面已经提及：到目前为止HotSpot JVM虚拟机只单独回收Old区的只有CMS GC。触发CMS GC条件比较简单，JVM有一个线程定时扫描Old区，时间间隔可以通过参数-XX:CMSWaitDuration设置（默认就是2s），扫描发现Old区占比超过参数-XX:CMSInitiatingOccupancyFraction设定值（CMS条件下默认为68%），就会触发CMS GC。建议搭配-XX:+UseCMSInitiatingOccupancyOnly参数使用，简化CMS GC触发条件，只有在Old区占比满足-XX:CMSInitiatingOccupancyFraction条件的情况下才触发CMS GC；

可参考的健康的GC状况给出建议CMS GC频率不超过1天/次，如果CMS GC频率1天发生数次，甚至上10次，说明你的GC情况病的不轻了，建议follow如下步骤进行初步症断：

  1. 检查Young区与Old区比值，尽量留60%以上的堆空间给Old区；
  2. 通过jstat查看每次YoungGC后晋升到Old区对象占比，如果发现每次YoungGC后Old区涨好几个百分点，甚至上10个点，说明有大对象，建议dump（参考jmap -dump:format=b,file=app.bin pid）后用MAT分析；
  3. 如果不停的CMS GC，Old区降不下去，建议先执行jmap -histo pid | head -n10 查看TOP10对象分布，如果除了[B和[C，即byte[]和char[]，还有其他占比较大的实例，如下图所示中排名第一的Object数组，也可通过dump后用MAT分析问题；
  4. 如果TOP10对象中有StandartSession对象，排查你的业务代码中有没有显示使用HttpSession，例如String id = request.getSession().getId();，一般的OLTP系统都是无状态的，几乎不会使用HttpSession，且HttpSession的的生命周期很长，会加快Old区增长速度；

FullGC

如果配置CMS，由于CMS采用标记清理算法，会有内存碎片的问题，推荐配置一个查看内存碎片程度的JVM参数：PrintFLSStatistics。

如果配置ParallelOldGC，那么每次Old区满后，会触发FullGC，如果FullGC频率过高，也可以通过上面OldGC提及的排查方法；

如果没有配置-XX:+DisableExplicitGC，即没有屏蔽System.gc()触发FullGC，那么可以通过排查GC日志中有System字样判断是否由System.gc()触发，日志样本如下：

1
558082.666: [Full GC (System) [PSYoungGen: 368K->0K(42112K)] [PSOldGen: 36485K->32282K(87424K)] 36853K->32282K(129536K) [PSPermGen: 34270K->34252K(196608K)], 0.2997530 secs]

或者通过jstat -gccause pid 2s pid判定，LGCC表示最近一次GC原因，如果为System.gc，表示由System.gc()触发，GCC表示当前GC原因，如果当前没有GC，那么就是No GC：

参考

  1. 你的JVM还好吗？GC初步诊断
  2. linux 性能监控 sar命令
  3. 深入理解swap交换分区理解及扩存
显示评论